1284511 - Slow script/Unresponsive Script dialogs appear frequently when resuming app

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[James Willcox (:snorp) ([e-mail]) (he/him)]

I've noticed recently I get a 'slow script' dialog frequently if I switch back to Fennec after being in another app. Seems to happen no matter what sites I have open. Not reproducible.

Comment 1

[James Willcox (:snorp) ([e-mail]) (he/him)]

:bkelly says this might be because we throttle timers[0] on mac/win but not on Android. Apparently we need to send some stuff on NS_WIDGET_SLEEP_OBSERVER_TOPIC[0] when sleeping/resuming.

[0] https://dxr.mozilla.org/mozilla-central/source/xpcom/threads/TimerThread.cpp#441
[1] https://dxr.mozilla.org/mozilla-central/search?q=NS_WIDGET_SLEEP_OBSERVER_TOPIC

Comment 2

[James Willcox (:snorp) ([e-mail]) (he/him)]

OK all of that is super old so maybe unrelated

Comment 3

[James Willcox (:snorp) ([e-mail]) (he/him)]

I saw this on Windows 10 laptop after sleep, though, so doesn't seem to be Fennec-specific. Moving to JS for lack of a better place.

Comment 4

[Johnny Stenback (:jst)]

Jim, Brad, here's another recent slow script related bug. Related to the e10s work we did for slow script dialogs?

Comment 5

[James Willcox (:snorp) ([e-mail]) (he/him)]

Comment #4

Comment 6

[Jim Mathies [:jimm]]

This is in the fennec product? I don't see how our e10s related work for desktop plays into this.

Comment 7

[James Willcox (:snorp) ([e-mail]) (he/him)]

Brad came up with some telemetry that seems to show badness starting on June 2

https://telemetry.mozilla.org/new-pipeline/evo.html#!aggregates=median&cumulative=0&end_date=2016-08-01&keys=!__none__!__none__&max_channel_version=nightly%252F50&measure=SLOW_SCRIPT_NOTICE_COUNT&min_channel_version=nightly%252F48&product=Fennec&sanitize=1&sort_keys=submissions&start_date=2016-06-07&trim=1&use_submission_date=0

Comment 8

[James Willcox (:snorp) ([e-mail]) (he/him)]

Bug 1276626 looks likely.

:arai, what do you think?

Comment 9

[James Willcox (:snorp) ([e-mail]) (he/him)]

Input from :mrbkap would be useful as well (see comment #7 and #8)

Comment 10

[Tooru Fujisawa [:arai]]

Triggered a build with logging.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c901052c3da3

will test once the build finishes.

Comment 11

[Tooru Fujisawa [:arai]]

okay, I got it.
the algorithm I used was wrong.

we need to calculate "how many times the half timeout happens" and "how long time elapsed from last RecordRuntimeActivity" separately.
will prepare a patch.

Comment 12

[Tooru Fujisawa [:arai]]

Attachment: Fix slow script check to use elapsed time from last check.

The bug in previous approach was that we increment mSlowScriptSecondHalfCount only by 1 even if long time elapsed, and it hits timeout everytime we check in watch dog, until RecordRuntimeActivity is called.

Then, I tried to increment mSlowScriptSecondHalfCount with proper amount, but I bumped into another issue:
if timeout is 10 seconds, we check every 5 seconds.
if 99.9 seconds elapsed without RecordRuntimeActivity because of sleep,
we would wait only extra 0.1 seconds before invoking interrupt, even if we increment mSlowScriptSecondHalfCount properly.

So, I changed the approach.
It would be simpler to record the last TimeSinceLastRuntimeStateChange value, and check the elapsed time from the that, and flip mSlowScriptSecondHalf every timeout.

This is the almost same approach that was used before bug 1276626 patch, in XPCJSRuntime.
  https://hg.mozilla.org/mozilla-central/rev/8272530c90ef

Comment 13

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

This was deemed blocking for 49 at the channel meeting today. Marking it as such.

Comment 14

[Tooru Fujisawa [:arai]]

It might be better just backing out bug 1276626 patch, at least for 49, as the case fixed by the patch should be less critical than this.

Comment 15

[Liz Henry (:lizzard) (relman/hg->git project)]

OK. It looks like the fix in 1276626 was for a specific case. Maybe we can backout as you suggest. The risk from my point of view is that, since the fix in that bug landed 3 months ago, in the time in between, we have landed more patches from something like 6000 other bugs.  So, I don't know how to tell quickly if something else depends on the work in bug 1276626.   We can try the backout, for the RC build and release on Tuesday, then we have the rest of that week to uncover any regressions.

Comment 16

[Tooru Fujisawa [:arai]]

try run on beta branch with backout bug 1276626 patch:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=40c0efa59bb0

will land the attachment 8787275 [details] [diff] [review] patch shortly to m-i, after test,
and also trigger another try run on beta branch with the patch.

Comment 17

[Tooru Fujisawa [:arai]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2872d7dca33b68a7c49adffeb2b671c28820ac60
Bug 1284511 - Fix slow script check to use elapsed time from last check. r=mrbkap

Comment 18

[Tooru Fujisawa [:arai]]

try run on beta branch with attachment 8787275 [details] [diff] [review]
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=cc5bf464f737

Comment 19

[Tooru Fujisawa [:arai]]

so far I don't see any test regression on beta tries.
can anyone test with actual case (laptop or android sleep) on those binaries?  or next nightly?

Comment 20

[Tooru Fujisawa [:arai]]

or, can anyone provide the steps to reproduce?
I cannot reproduce the issue on Windows 10 laptop with 49.0b8.
(I opened treeherder in 2 tabs and tries sleep with ~1 minutes several times)

snorp, do you know?

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/2872d7dca33b

Comment 22

[Tooru Fujisawa [:arai]]

Attachment: (mozilla-aurora) Fix slow script check to use elapsed time from last check. r=mrbkap

for now, attaching backported patches.
I'm still trying to reproduce the issue, but no luck...

Comment 23

[Tooru Fujisawa [:arai]]

Attachment: (mozilla-beta) Fix slow script check to use elapsed time from last check. r=mrbkap

Comment 24

[Tooru Fujisawa [:arai]]

Comment on attachment 8787972 [details] [diff] [review]
(mozilla-aurora) Fix slow script check to use elapsed time from last check. r=mrbkap

for now, requesting uplift.
once someone verified the fix, I will rewrite the uplift request message.


Approval Request Comment
> [Feature/regressing bug #]
Bug 1276626.

> [User impact if declined]
Slow script dialog may be shown after sleep

> [Describe test coverage new/current, TreeHerder]
This needs manual test, as it's related to sleep, and it cannot be done in automated tests.

> [Risks and why]
Medium, as this is not yet tested on the env that hits the issue.
I cannot reproduce the issue locally with affectes builds (aurora/nightly).

> [String/UUID change made/needed]
None

Comment 25

[Tooru Fujisawa [:arai]]

Comment on attachment 8787973 [details] [diff] [review]
(mozilla-beta) Fix slow script check to use elapsed time from last check. r=mrbkap

Approval Request Comment
> [Feature/regressing bug #]
Bug 1276626.

> [User impact if declined]
Slow script dialog may be shown after sleep

> [Describe test coverage new/current, TreeHerder]
This needs manual test, as it's related to sleep, and it cannot be done in automated tests.

> [Risks and why]
Medium, as this is not yet tested on the env that hits the issue.
I cannot reproduce the issue locally with affected builds (aurora/nightly).

> [String/UUID change made/needed]
None

Comment 26

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8787973 [details] [diff] [review]
(mozilla-beta) Fix slow script check to use elapsed time from last check. r=mrbkap

OK, let's try with this patch, taking it to 49 rc 1
FYI, we will have to do a second rc anyway for bug 1297687

Comment 27

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/37c314d53f82
  https://hg.mozilla.org/releases/mozilla-beta/rev/9aa5886a1563

Comment 28

[James Willcox (:snorp) ([e-mail]) (he/him)]

I don't have solid STR. I tried for a while to find some, but wasn't able to come up with anything.

Comment 29

[James Willcox (:snorp) ([e-mail]) (he/him)]

We should be able to use telemetry to figure out if the patch helps or not.

Comment 30

[Andrew Overholt [:overholt]]

*Almost* every time I come back from sleep on Windows 10 running Aurora I see a slow script dialog for IRCCloud in a pinned tab. Weak STR but maybe useful.

Comment 31

[Marco Castelluccio [:marco]]

(In reply to Andrew Overholt [:overholt] from comment #30)
> *Almost* every time I come back from sleep on Windows 10 running Aurora I
> see a slow script dialog for IRCCloud in a pinned tab. Weak STR but maybe
> useful.

I've noticed more frequent slow script dialogs too on Aurora, often in the browser/base/content/browser.js script. I wasn't doing anything and Firefox wasn't being slow or anything, so it looked like a false positive.

Comment 32

[Tooru Fujisawa [:arai]]

Thanks.
now I'm testing on IRCCloud, but so far I don't see the dialog.
Does the issue still happen on today's aurora?

Comment 33

[Liz Henry (:lizzard) (relman/hg->git project)]

Just came up for me on 49 RC1 on a gmail tab after resuming from sleep with this error: Script: https://plus.google.com/_/scs/…cCMjOvovKNJ3foLAYjuM34xrVTC2sw:114 .  I don't particularly use google plus. But I think this is from the little red g+ notification number in the upper corner of gmail. Some sort of push notification thing?

Comment 34

[Tooru Fujisawa [:arai]]

should we try backing out whole patches (this bug and bug 1276626) then?

Comment 35

[Tooru Fujisawa [:arai]]

Attachment: (mozilla-central) Backed out changeset 8272530c90ef (bug 1276626)

this bug's patch should be able to be backed out cleanly.
Here are patches that backout bug 1276626 patch.

Comment 36

[Tooru Fujisawa [:arai]]

Attachment: (mozilla-aurora) Backed out changeset 8272530c90ef (bug 1276626)

Comment 37

[Tooru Fujisawa [:arai]]

Attachment: (mozilla-beta) Backed out changeset 8272530c90ef (bug 1276626)

Comment 38

[Tooru Fujisawa [:arai]]

Comment on attachment 8789180 [details] [diff] [review]
(mozilla-aurora) Backed out changeset 8272530c90ef (bug 1276626)

about mozilla-central, I'll land backout patches shortly.


asking approval for backing out bug 1284511 patch and this bug's patch:
  https://hg.mozilla.org/releases/mozilla-aurora/rev/37c314d53f82
  https://hg.mozilla.org/releases/mozilla-aurora/rev/8272530c90ef

this patch backs out 8272530c90ef.
37c314d53f82 should be able to be backed out cleanly.


Approval Request Comment
> [Feature/regressing bug #]
bug 1284511 and this bug
bug 1284511 caused the issue, tried a fix on this bug, but it didn't work.

> [User impact if declined]
Slow script dialog may be shown after sleep

> [Describe test coverage new/current, TreeHerder]
This needs manual test, as it's related to sleep, and it cannot be done in automated tests.

> [Risks and why]:
Medium, as this is not yet tested on the env that hits the issue.
I still cannot reproduce the issue locally with affected builds.

> [String/UUID change made/needed]
None

Comment 39

[Tooru Fujisawa [:arai]]

Comment on attachment 8789181 [details] [diff] [review]
(mozilla-beta) Backed out changeset 8272530c90ef (bug 1276626)

also, asking approval for backing out bug 1284511 patch and this bug's patch:
  https://hg.mozilla.org/releases/mozilla-beta/rev/9aa5886a1563
  https://hg.mozilla.org/releases/mozilla-beta/rev/8272530c90ef

this patch backout 8272530c90ef.
9aa5886a1563 should be able to be backed out cleanly.


Approval Request Comment
> [Feature/regressing bug #]
bug 1284511 and this bug
bug 1284511 caused the issue, tried a fix on this bug, but it didn't work.

> [User impact if declined]
Slow script dialog may be shown after sleep

> [Describe test coverage new/current, TreeHerder]
This needs manual test, as it's related to sleep, and it cannot be done in automated tests.

> [Risks and why]:
Medium, as this is not yet tested on the env that hits the issue.
I still cannot reproduce the issue locally with affected builds.

> [String/UUID change made/needed]
None

Comment 40

[Tooru Fujisawa [:arai]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4248b124b502f12f1a31179aa2703da95161091e
Backed out changeset 2872d7dca33b (bug 1284511) r=blassey

Comment 41

[Tooru Fujisawa [:arai]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c0a3eb567948034fe6871a814cdad0dbb127d08e
Backed out changeset 8272530c90ef (bug 1276626) for bug 1284511 r=blassey

Comment 42

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

(In reply to Andrew Overholt [:overholt] from comment #30)
> *Almost* every time I come back from sleep on Windows 10 running Aurora I
> see a slow script dialog for IRCCloud in a pinned tab. Weak STR but maybe
> useful.

+1 to these STR from Andrew. In my case though, on RC1, I have yet to see the slow script dialog pop up. So I for one feel the change we landed in RC1 worked, especially on win10.

Are we certain everyone is testing against RC1 and not the earlier builds?

Comment 43

[Liz Henry (:lizzard) (relman/hg->git project)]

I am getting the slow script warning in gmail and google docs after resuming from sleep (Mac, 10.11, with the RC2 build today) But I am just one person so consider that anecdotal, and I can't reproduce it every time. 
 
I think Brad was judging from the Nightly telemetry data that the fix in nightly didn't decrease the slow script reports.

Comment 44

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Merged backout:
https://hg.mozilla.org/mozilla-central/rev/176aff980979
https://hg.mozilla.org/mozilla-central/rev/5ff6c6e67186

Comment 45

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/4248b124b502
https://hg.mozilla.org/mozilla-central/rev/c0a3eb567948

Comment 46

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8789180 [details] [diff] [review]
(mozilla-aurora) Backed out changeset 8272530c90ef (bug 1276626)

Let's uplift the backout to aurora as well, and see if we get any useful user feedback. And, we should know more from telemetry on nightly by Monday.

Comment 47

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/68f57be1e461
https://hg.mozilla.org/releases/mozilla-aurora/rev/28878b37a89e

Comment 48

[u52928]

I don't know if this is related, but the Fidelity.com website is so slow, it's been rendered virtually unusable in v. 49 beta. It works fine in ESR and is a bit better in Nightly.

Comment 49

[u52928]

In relation to my previous comment, I'm talking about after one logs in. Ummmmm, sorry, but I'm not going to send you my log-in data so you can test it. 
;-)

I don't, however, get the message that a script is slowing down Fx. It's just that the elements take forever to load and every time I try to visit the page, at one point or another, I get the message in the title bar (which eventually goes away) "Program not responding".

By the way, I'm using the very latest version of 49 beta (07 Sep).

Comment 50

[u52928]

Sorry, I should have mentioned this earlier (I still find it stupid that there's no way to edit comments): With a new profile it works fine, but I've removed No Script and UBlock Origin, and this hasn't helped.

Comment 51

[fireattack [:fireattack]]

Is bug 1294782 related to this? It's not from the resuming though, just put Firefox on background for a while and I will receive unresponsive script error.

Comment 52

[Liz Henry (:lizzard) (relman/hg->git project)]

After discussion about telemetry results with chutten, I think we will go ahead and try uplifting the backout for the RC3 build. He will post more details soon.

Comment 53

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8789181 [details] [diff] [review]
(mozilla-beta) Backed out changeset 8272530c90ef (bug 1276626)

[Triage Comment]

Let's bring the backout to beta and release for the RC3 build.

Comment 54

[Chris H-C :chutten]

At :lizzard's and :bsmedberg's behest, I analyzed [1] the current data we have on the probe SLOW_SCRIPT_NOTICE_COUNT (which counts the number of times a user sees the slow script dialog). It is a comparison between nightly 0910 and nightly 0903 (Saturdays, to maintain day-of-week volume comparability).

This analysis is as-of-yet unreviewed, but shows data consistent with what's seen on telemetry.mozilla.org[2]. Specifically, that the number of reports (and clients submitting those reports) of slow script notices has dropped to 20% of previous figures. I suspect not all pings and clients have reported in for the build, but assuming that the pings and clients are representative, we can say the following about rates:

There are now more pings from fewer clients reporting more notices. Or, to put it colloquially, it seems as though we have traded a nightly where some people had poor experiences for a nightly where few people had hideous experiences.

All that with the needle on the notices-per-usage-hour barely moving at all.

This seems to be a return of this measure to the values and volumes experienced earlier this year until the beginning of June, which is consistent with the patchset backed out.

[1]: https://gist.github.com/chutten/feb43ea722a7a0dcacfe399ba03a1ffe
[2]: https://mzl.la/2cHTHfX

Comment 55

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-beta/rev/41b93f219e9f
https://hg.mozilla.org/releases/mozilla-beta/rev/ddeb7907bc1e

Comment 56

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-release/rev/41b93f219e9f
https://hg.mozilla.org/releases/mozilla-release/rev/ddeb7907bc1e

Comment 57

[David Bolter [:davidb] (NeedInfo me for attention)]

(In reply to Chris H-C :chutten from comment #54)

> There are now more pings from fewer clients reporting more notices. Or, to
> put it colloquially, it seems as though we have traded a nightly where some
> people had poor experiences for a nightly where few people had hideous
> experiences.

Thanks for all the details! Is there a bug already filed for helping those people?

Comment 58

[Chris H-C :chutten]

(In reply to David Bolter [:davidb] from comment #57)
> (In reply to Chris H-C :chutten from comment #54)
> 
> > There are now more pings from fewer clients reporting more notices. Or, to
> > put it colloquially, it seems as though we have traded a nightly where some
> > people had poor experiences for a nightly where few people had hideous
> > experiences.
> 
> Thanks for all the details! Is there a bug already filed for helping those
> people?

I think bug 1276626 may be that bug, as it was the effort to try and improve what was thought to be the cause.